See dial tcp i/o timeouts once a day

[sigmavirus24]

I use Rack every day. The first request of the day, I always get:

error   Post https://dfw.servers.api.rackspacecloud.com/v2/<tenant>/servers/<server-uuid>/action: dial tcp: i/o timeout

It's as if there's some kind of connection pooling that's happening between processes and making this first request clears a connection. It seems unlikely that there's connection pooling, but it's a bit annoying regardless.

[jrperritt]

Can you post the [appropriately redacted] output of this happening with --log debug?

[sigmavirus24]

I can tomorrow =) (which is likely when I'll see it again)

[sigmavirus24]

MMR298FD58:~ rack servers instance rebuild --log info --id <server-id> --image-id 09de0a66-3156-48b4-90a5-1cf25a905207 --admin-pass <hah>
INFO[0000] Global Options:
output: table (from default value)
log: info (from command-line)


INFO[0000] Authentication Credentials:
region: DFW (from config file (profile: DEFAULT))
auth-url: https://identity.api.rackspacecloud.com/v2.0/ (from default value)
username: <redacted> (from config file (profile: DEFAULT))
api-key: <redacted> (from config file (profile: DEFAULT))


INFO[0000] Using public endpoint
INFO[0000] Looking in the cache for cache key: <redacted>,https://identity.api.rackspacecloud.com/v2.0/,DFW,compute,public

INFO[0000] Using token from cache: <redacted>

INFO[0000] Request URL: https://dfw.servers.api.rackspacecloud.com/v2/<tenant>/servers/<server-id>

failed MSpanList_Insert 0xd49c20 0x42d62ae70e2 0x0 0x0
fatal error: MSpanList_Insert

runtime stack:
runtime.throw(0x6f44f0, 0x10)
        /usr/local/Cellar/go/1.6/libexec/src/runtime/panic.go:530 +0x90
runtime.(*mSpanList).insert(0x9fb9a8, 0xd49c20)
        /usr/local/Cellar/go/1.6/libexec/src/runtime/mheap.go:933 +0x293
runtime.(*mheap).freeSpanLocked(0x9fb1a0, 0xd49c20, 0x100, 0x0)
        /usr/local/Cellar/go/1.6/libexec/src/runtime/mheap.go:809 +0x4be
runtime.(*mheap).grow(0x9fb1a0, 0x8, 0x0)
        /usr/local/Cellar/go/1.6/libexec/src/runtime/mheap.go:675 +0x2a0
runtime.(*mheap).allocSpanLocked(0x9fb1a0, 0x1, 0xd49ba8)
        /usr/local/Cellar/go/1.6/libexec/src/runtime/mheap.go:553 +0x4e3
runtime.(*mheap).alloc_m(0x9fb1a0, 0x1, 0x3, 0xd49ba8)
        /usr/local/Cellar/go/1.6/libexec/src/runtime/mheap.go:437 +0x119
runtime.(*mheap).alloc.func1()
        /usr/local/Cellar/go/1.6/libexec/src/runtime/mheap.go:502 +0x41
runtime.systemstack(0x7fff5fbff618)
        /usr/local/Cellar/go/1.6/libexec/src/runtime/asm_amd64.s:307 +0xab
runtime.(*mheap).alloc(0x9fb1a0, 0x1, 0x10000000003, 0x19c8f)
        /usr/local/Cellar/go/1.6/libexec/src/runtime/mheap.go:503 +0x63
runtime.(*mcentral).grow(0x9fc5c0, 0x0)
        /usr/local/Cellar/go/1.6/libexec/src/runtime/mcentral.go:209 +0x93
runtime.(*mcentral).cacheSpan(0x9fc5c0, 0xd49ba8)
        /usr/local/Cellar/go/1.6/libexec/src/runtime/mcentral.go:89 +0x47d
runtime.(*mcache).refill(0xb184b0, 0x3, 0xd49ba8)
        /usr/local/Cellar/go/1.6/libexec/src/runtime/mcache.go:119 +0xcc
runtime.mallocgc.func2()
        /usr/local/Cellar/go/1.6/libexec/src/runtime/malloc.go:642 +0x2b
runtime.systemstack(0x9f6400)
        /usr/local/Cellar/go/1.6/libexec/src/runtime/asm_amd64.s:291 +0x79
runtime.mstart()
        /usr/local/Cellar/go/1.6/libexec/src/runtime/proc.go:1048

goroutine 12 [running]:
runtime.systemstack_switch()
        /usr/local/Cellar/go/1.6/libexec/src/runtime/asm_amd64.s:245 fp=0xc8202a84d8 sp=0xc8202a84d0
runtime.mallocgc(0x20, 0x5fc8a0, 0xc800000000, 0x4)
        /usr/local/Cellar/go/1.6/libexec/src/runtime/malloc.go:643 +0x869 fp=0xc8202a85b0 sp=0xc8202a84d8
runtime.newobject(0x5fc8a0, 0x17)
        /usr/local/Cellar/go/1.6/libexec/src/runtime/malloc.go:781 +0x42 fp=0xc8202a85d8 sp=0xc8202a85b0
reflect.MakeSlice(0xb6c0a8, 0x4bf300, 0x120, 0x120, 0x0, 0x0, 0x0)
        /usr/local/Cellar/go/1.6/libexec/src/reflect/value.go:2044 +0x1d4 fp=0xc8202a8648 sp=0xc8202a85d8
encoding/asn1.parseField(0x4bf300, 0xc8202fe100, 0x197, 0xc8202fc2e4, 0x129, 0x2da, 0x5, 0x0, 0x0, 0x0, ...)
        /usr/local/Cellar/go/1.6/libexec/src/encoding/asn1/asn1.go:863 +0x2565 fp=0xc8202a8dd0 sp=0xc8202a8648
encoding/asn1.parseField(0x5f24a0, 0xc8202fe0e0, 0x199, 0xc8202fc27f, 0x22b, 0x33f, 0x61, 0x0, 0x0, 0x0, ...)
        /usr/local/Cellar/go/1.6/libexec/src/encoding/asn1/asn1.go:851 +0x31d2 fp=0xc8202a9558 sp=0xc8202a8dd0
encoding/asn1.parseSequenceOf(0xc8202fc27f, 0x22b, 0x33f, 0xb6c0a8, 0x4bab00, 0xb6c0a8, 0x5f24a0, 0x4bab00, 0xc8202f3c20, 0x97, ...)
        /usr/local/Cellar/go/1.6/libexec/src/encoding/asn1/asn1.go:558 +0x455 fp=0xc8202a9690 sp=0xc8202a9558
encoding/asn1.parseField(0x4bab00, 0xc8202eae38, 0x197, 0xc8202fc008, 0x4a2, 0x5b6, 0x26f, 0x101, 0x0, 0xc8202f1258, ...)
        /usr/local/Cellar/go/1.6/libexec/src/encoding/asn1/asn1.go:867 +0x2752 fp=0xc8202a9e18 sp=0xc8202a9690
encoding/asn1.parseField(0x658420, 0xc8202eac18, 0x199, 0xc8202fc004, 0x5ba, 0x5ba, 0x0, 0x0, 0x0, 0x0, ...)
        /usr/local/Cellar/go/1.6/libexec/src/encoding/asn1/asn1.go:851 +0x31d2 fp=0xc8202aa5a0 sp=0xc8202a9e18
encoding/asn1.parseField(0x610940, 0xc8202eac00, 0x199, 0xc8202fc000, 0x5be, 0x5be, 0x0, 0x0, 0x0, 0x0, ...)
        /usr/local/Cellar/go/1.6/libexec/src/encoding/asn1/asn1.go:851 +0x31d2 fp=0xc8202aad28 sp=0xc8202aa5a0
encoding/asn1.UnmarshalWithParams(0xc8202fc000, 0x5be, 0x5be, 0x4a3280, 0xc8202eac00, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
        /usr/local/Cellar/go/1.6/libexec/src/encoding/asn1/asn1.go:990 +0x16e fp=0xc8202aae10 sp=0xc8202aad28
encoding/asn1.Unmarshal(0xc8202fc000, 0x5be, 0x5be, 0x4a3280, 0xc8202eac00, 0x0, 0x0, 0x0, 0x0, 0x0)
        /usr/local/Cellar/go/1.6/libexec/src/encoding/asn1/asn1.go:983 +0x8f fp=0xc8202aae78 sp=0xc8202aae10
crypto/x509.ParseCertificate(0xc8202fc000, 0x5be, 0x5be, 0xb, 0x0, 0x0)
        /usr/local/Cellar/go/1.6/libexec/src/crypto/x509/x509.go:1187 +0x91 fp=0xc8202aaf20 sp=0xc8202aae78
crypto/x509.(*CertPool).AppendCertsFromPEM(0xc820292060, 0xc820213d58, 0x3aef5, 0x7a0a8, 0xc820292001)
        /usr/local/Cellar/go/1.6/libexec/src/crypto/x509/cert_pool.go:96 +0x11d fp=0xc8202aaf88 sp=0xc8202aaf20
crypto/x509.execSecurityRoots(0x1201a5, 0x0, 0x0)
        /usr/local/Cellar/go/1.6/libexec/src/crypto/x509/root_darwin.go:23 +0x23e fp=0xc8202ab060 sp=0xc8202aaf88
crypto/x509.initSystemRoots()
        /usr/local/Cellar/go/1.6/libexec/src/crypto/x509/root_nocgo_darwin.go:10 +0x18 fp=0xc8202ab080 sp=0xc8202ab060
sync.(*Once).Do(0xa13688, 0x7b4648)
        /usr/local/Cellar/go/1.6/libexec/src/sync/once.go:44 +0xe4 fp=0xc8202ab0a8 sp=0xc8202ab080
crypto/x509.systemRootsPool(0x0)
        /usr/local/Cellar/go/1.6/libexec/src/crypto/x509/root.go:15 +0x2f fp=0xc8202ab0c0 sp=0xc8202ab0a8
crypto/x509.(*Certificate).Verify(0xc82007b680, 0xc820124180, 0x22, 0xc820124f60, 0x0, 0xecf3a6c20, 0x3da1eac, 0x9f5e80, 0x0, 0x0, ...)
        /usr/local/Cellar/go/1.6/libexec/src/crypto/x509/verify.go:241 +0x1de fp=0xc8202ab318 sp=0xc8202ab0c0
crypto/tls.(*clientHandshakeState).doFullHandshake(0xc8202abe38, 0x0, 0x0)
        /usr/local/Cellar/go/1.6/libexec/src/crypto/tls/handshake_client.go:278 +0x6e9 fp=0xc8202ab9d0 sp=0xc8202ab318
crypto/tls.(*Conn).clientHandshake(0xc82015c000, 0x0, 0x0)
        /usr/local/Cellar/go/1.6/libexec/src/crypto/tls/handshake_client.go:213 +0x1737 fp=0xc8202abee8 sp=0xc8202ab9d0
crypto/tls.(*Conn).Handshake(0xc82015c000, 0x0, 0x0)
        /usr/local/Cellar/go/1.6/libexec/src/crypto/tls/conn.go:1033 +0xec fp=0xc8202abf28 sp=0xc8202abee8
net/http.(*Transport).dialConn.func3(0xc82015c000, 0xc82011d3c0, 0xc820112ae0)
        /usr/local/Cellar/go/1.6/libexec/src/net/http/transport.go:824 +0x21 fp=0xc8202abf68 sp=0xc8202abf28
runtime.goexit()
        /usr/local/Cellar/go/1.6/libexec/src/runtime/asm_amd64.s:1998 +0x1 fp=0xc8202abf70 sp=0xc8202abf68
created by net/http.(*Transport).dialConn
        /usr/local/Cellar/go/1.6/libexec/src/net/http/transport.go:829 +0x986

goroutine 1 [chan receive]:
github.com/rackspace/rack/handler.Handle(0xb6ca88, 0xc82002c040)
        /Users/sigmavirus24/openstack/rackspace/src/github.com/rackspace/rack/handler/handle.go:112 +0x484
github.com/rackspace/rack/commands/serverscommands/instancecommands.actionRebuild(0xc8200ccfc0)
        /Users/sigmavirus24/openstack/rackspace/src/github.com/rackspace/rack/commands/serverscommands/instancecommands/rebuild.go:80 +0xc9
github.com/rackspace/rack/internal/github.com/codegangsta/cli.Command.Run(0x6992f0, 0x7, 0x0, 0x0, 0x0, 0x0, 0x0, 0xc820089480, 0x7b, 0x70d2e0, ...)
        /Users/sigmavirus24/openstack/rackspace/src/github.com/rackspace/rack/internal/github.com/codegangsta/cli/command.go:118 +0x1093
github.com/rackspace/rack/internal/github.com/codegangsta/cli.(*App).RunAsSubcommand(0xc8200f8200, 0xc8200cce00, 0x0, 0x0)
        /Users/sigmavirus24/openstack/rackspace/src/github.com/rackspace/rack/internal/github.com/codegangsta/cli/app.go:257 +0xc83
github.com/rackspace/rack/internal/github.com/codegangsta/cli.Command.startApp(0x6a7920, 0x8, 0x0, 0x0, 0x0, 0x0, 0x0, 0x70da80, 0x1f, 0x0, ...)
        /Users/sigmavirus24/openstack/rackspace/src/github.com/rackspace/rack/internal/github.com/codegangsta/cli/command.go:183 +0x4e5
github.com/rackspace/rack/internal/github.com/codegangsta/cli.Command.Run(0x6a7920, 0x8, 0x0, 0x0, 0x0, 0x0, 0x0, 0x70da80, 0x1f, 0x0, ...)
        /Users/sigmavirus24/openstack/rackspace/src/github.com/rackspace/rack/internal/github.com/codegangsta/cli/command.go:45 +0x162f
github.com/rackspace/rack/internal/github.com/codegangsta/cli.(*App).RunAsSubcommand(0xc8200f8100, 0xc8200ccd20, 0x0, 0x0)
        /Users/sigmavirus24/openstack/rackspace/src/github.com/rackspace/rack/internal/github.com/codegangsta/cli/app.go:257 +0xc83
github.com/rackspace/rack/internal/github.com/codegangsta/cli.Command.startApp(0x6996d8, 0x7, 0x0, 0x0, 0x0, 0x0, 0x0, 0x76a9a0, 0x39, 0x0, ...)
        /Users/sigmavirus24/openstack/rackspace/src/github.com/rackspace/rack/internal/github.com/codegangsta/cli/command.go:183 +0x4e5
github.com/rackspace/rack/internal/github.com/codegangsta/cli.Command.Run(0x6996d8, 0x7, 0x0, 0x0, 0x0, 0x0, 0x0, 0x76a9a0, 0x39, 0x0, ...)
        /Users/sigmavirus24/openstack/rackspace/src/github.com/rackspace/rack/internal/github.com/codegangsta/cli/command.go:45 +0x162f
github.com/rackspace/rack/internal/github.com/codegangsta/cli.(*App).Run(0xc8200f8000, 0xc82000a180, 0xc, 0xc, 0x0, 0x0)
        /Users/sigmavirus24/openstack/rackspace/src/github.com/rackspace/rack/internal/github.com/codegangsta/cli/app.go:160 +0xbaa
main.main()
        /Users/sigmavirus24/openstack/rackspace/src/github.com/rackspace/rack/main.go:36 +0x3c1

goroutine 7 [chan receive]:
net/http.(*Transport).dialConn(0xc82000a240, 0x0, 0xc8200eeb60, 0x5, 0xc820124180, 0x26, 0x0, 0x0, 0x0)
        /usr/local/Cellar/go/1.6/libexec/src/net/http/transport.go:830 +0x9c2
net/http.(*Transport).getConn.func4(0xc82000a240, 0x0, 0xc8200eeb60, 0x5, 0xc820124180, 0x26, 0xc820112660)
        /usr/local/Cellar/go/1.6/libexec/src/net/http/transport.go:702 +0x66
created by net/http.(*Transport).getConn
        /usr/local/Cellar/go/1.6/libexec/src/net/http/transport.go:704 +0x262

goroutine 6 [select]:
net/http.(*Transport).getConn(0xc82000a240, 0xc8200cd0a0, 0x0, 0xc8200eeb60, 0x5, 0xc820124180, 0x26, 0x0, 0x0, 0x0)
        /usr/local/Cellar/go/1.6/libexec/src/net/http/transport.go:707 +0x4ef
net/http.(*Transport).RoundTrip(0xc82000a240, 0xc8200cd0a0, 0x10, 0x0, 0x0)
        /usr/local/Cellar/go/1.6/libexec/src/net/http/transport.go:307 +0x7e9
github.com/rackspace/rack/auth.(*LogRoundTripper).RoundTrip(0xc820114c40, 0xc8200cd0a0, 0x0, 0x0, 0x0)
        /Users/sigmavirus24/openstack/rackspace/src/github.com/rackspace/rack/auth/clients.go:351 +0x65b
net/http.send(0xc8200cd0a0, 0xb6ccd0, 0xc820114c40, 0x0, 0x0, 0x0, 0xc8200eec40, 0x0, 0x0)
        /usr/local/Cellar/go/1.6/libexec/src/net/http/client.go:260 +0x6b7
net/http.(*Client).send(0xc82008b3e8, 0xc8200cd0a0, 0x0, 0x0, 0x0, 0xc82011cec0, 0x0, 0x0)
        /usr/local/Cellar/go/1.6/libexec/src/net/http/client.go:155 +0x185
net/http.(*Client).doFollowingRedirects(0xc82008b3e8, 0xc8200cd0a0, 0x7b5870, 0x0, 0x0, 0x0)
        /usr/local/Cellar/go/1.6/libexec/src/net/http/client.go:475 +0x8a4
net/http.(*Client).Do(0xc82008b3e8, 0xc8200cd0a0, 0xa, 0x0, 0x0)
        /usr/local/Cellar/go/1.6/libexec/src/net/http/client.go:191 +0x1e4
github.com/rackspace/rack/internal/github.com/rackspace/gophercloud.(*ProviderClient).Request(0xc82008b3b0, 0x696128, 0x4, 0xc8200eeb60, 0x68, 0x4cf0a0, 0xc820124030, 0x0, 0x0, 0x4abda0, ...)
        /Users/sigmavirus24/openstack/rackspace/src/github.com/rackspace/rack/internal/github.com/rackspace/gophercloud/provider_client.go:165 +0x67c
github.com/rackspace/rack/internal/github.com/rackspace/gophercloud.(*ProviderClient).Post(0xc82008b3b0, 0xc8200eeb60, 0x68, 0x4cf0a0, 0xc820124030, 0xc8200f5fb0, 0xc820109d48, 0x1, 0x0, 0x0)
        /Users/sigmavirus24/openstack/rackspace/src/github.com/rackspace/rack/internal/github.com/rackspace/gophercloud/provider_client.go:332 +0x21a
github.com/rackspace/rack/internal/github.com/rackspace/gophercloud/openstack/compute/v2/servers.Rebuild(0xc8200f5f20, 0xc8200f5f50, 0x24, 0xb6cd58, 0xc820089a80, 0x0, 0x0, 0x0, 0x0, 0x0)
        /Users/sigmavirus24/openstack/rackspace/src/github.com/rackspace/rack/internal/github.com/rackspace/gophercloud/openstack/compute/v2/servers/requests.go:585 +0x42b
github.com/rackspace/rack/internal/github.com/rackspace/gophercloud/rackspace/compute/v2/servers.Rebuild(0xc8200f5f20, 0xc8200f5f50, 0x24, 0xb6cd58, 0xc820089a80, 0x0, 0x0, 0x0, 0x0, 0x0)
        /Users/sigmavirus24/openstack/rackspace/src/github.com/rackspace/rack/internal/github.com/rackspace/gophercloud/rackspace/compute/v2/servers/delegate.go:54 +0x77
github.com/rackspace/rack/commands/serverscommands/instancecommands.(*commandRebuild).Execute(0xc82002c040, 0xc8201222d0)
        /Users/sigmavirus24/openstack/rackspace/src/github.com/rackspace/rack/commands/serverscommands/instancecommands/rebuild.go:146 +0xbc
github.com/rackspace/rack/handler.handleExecute.func4(0xb6ca88, 0xc82002c040, 0xc820015900, 0x9f16a0, 0xb, 0xb, 0x4a6ca0, 0xc820114c80, 0x0, 0x0, ...)
        /Users/sigmavirus24/openstack/rackspace/src/github.com/rackspace/rack/handler/handle.go:185 +0x6e
created by github.com/rackspace/rack/handler.handleExecute
        /Users/sigmavirus24/openstack/rackspace/src/github.com/rackspace/rack/handler/handle.go:188 +0x9cc

This reminds me that I had built a local copy to work around issues I had with rebuilding servers from an older versions.

Let me update that and test it out.

[jrperritt]

Hmm, that's an error I've never seen before. Seems like it might be this bug that was recently filed in the Go repo. If so, not much we can do other than rebuild rack with Go 1.7. Can you give that a shot and see if the problem persists?

[sigmavirus24]

I just finished upgrading to the the latest commit of Go and was finally able to recompile rack. (I was getting segmentation faults before) and rack works again!

[jrperritt]

Great, thanks for reporting and testing this.